Repository: pinpoint-apm/pinpoint-c-agent (language: python)

Issue:
[StreamServerLayer.py:68] peer error:[Errno 104] Connection reset by peer
I'm running a PHP cron job on Kubernetes which ending with the following trace:

```
[pinpoint] [1] [1]#55 pinpoint_end_trace Done!
--
  | [pinpoint] [1] [1]#128 add clues:330:20765.640625 KB
  | [pinpoint] [1] [1]this span:({"E":12325,"FT":1500,"S":1610711645350,"appid":"sid.ping-lost","appname":"sid","calls":[{"E":34,"S":142,"calls":[{"E":5,"S":165,"clues":["-1:SHOW FULL COLUMNS FROM `audit_entry`","21:SHOW FULL COLUMNS FROM `audit_entry`"],"dst":"mysql:host=uat.fr;port=3306;dbname=sid-uat","name":"yii\\db\\Command::internalExecute","stp":"2101"}],"clues":["-1:fetchAll","21:SHOW FULL COLUMNS FROM `audit_entry`"],"dst":"mysql:host=uat.fr;port=3306;dbname=sid-uat","name":"yii\\db\\Command::queryInternal","stp":"2101"},{"E":9,"S":178,"calls":[{"E":8,"S":179,"clues":["-1:SELECT\n    `kcu`.`CONSTRAINT_NAME` AS `constraint_name`,\n    `kcu`.`COLUMN_NAME` AS `column_name`,\n    `kcu`.`REFERENCED_TABLE_NAME` AS `referenced_table_name`,\n    `kcu`.`REFERENCED_COLUMN_NAME` AS `referenced_column_name`\nFROM `information_schema`.`REFERENTIAL_CONSTRAINTS` AS `rc`\nJOIN `information_schema`.`KEY_COLUMN_USAGE` AS `kcu` ON\n    (\n        `kcu`.`CONSTRAINT_CATALOG` = `rc`.`CONSTRAINT_CATALOG` OR\n        (`kcu`.`CONSTRAINT_CATALOG` IS NULL AND `rc`.`CONSTRAINT_CATALOG` IS NULL)\n    ) AND\n    `kcu`.`CONSTRAINT_SCHEMA` = `rc`.`CONSTRAINT_SCHEMA` AND\n    `kcu`.`CONSTRAINT_NAME` = `rc`.`CONSTRAINT_NAME`\nWHERE `rc`.`CONSTRAINT_SCHEMA` = database() AND `kcu`.`TABLE_SCHEMA` = database()\nAND `rc`.`TABLE_NAME` = 'audit_entry' AND `kcu`.`TABLE_NAME` = 'audit_entry'","21:SELECT\n    `kcu`.`CONSTRAINT_NAME` AS `constraint_name`,\n    `kcu`.`COLUMN_NAME` AS `column_name`,\n    `kcu`.`REFERENCED_TABLE_NAME` AS `referenced_table_name`,\n    `kcu`.`REFERENCED_COLUMN_NAME` AS `referenced_column_name`\nFROM `information_schema`.`REFERENTIAL_CONSTRAINTS` AS `rc`\nJOIN `information_schema`.`KEY_COLUMN_USAGE` AS `kcu` ON\n    (\n        `kcu`.`CONSTRAINT_CATALOG` = `rc`.`CONSTRAINT_CATALOG` OR\n        (`kcu`.`CONSTRAINT_CATALOG` IS NULL AND `rc`.`CONSTRAINT_CATALOG` IS NULL)\n    ) AND\n    `kcu`.`CONSTRAINT_SCHEMA` = `rc`.`CONSTRAINT_SCHEMA` AND\n    `kcu`.`CONSTRAINT_NAME` = `rc`.`CONSTRAINT_NAME`\nWHERE `rc`.`CONSTRAINT_SCHEMA` = database() AND `kcu`.`TABLE_SCHEMA` = database()\nAND `rc`.`TABLE_NAME` = 'audit_entry' AND `kcu`.`TABLE_NAME` = 'audit_entry'"],"dst":"mysql:host=uat..fr;port=3306;dbname=sid-uat","name":"yii\\db\\Command::internalExecute","stp":"2101"}],"clues":["-1:fetchAll","21:SELECT\n    `kcu`.`CONSTRAINT_NAME` AS `constraint_name`,\n    `kcu`.`COLUMN_NAME` AS `column_name`,\n    `kcu`.`REFERENCED_TABLE_NAME` AS `referenced_table_name`,\n    `kcu`.`REFERENCED_COLUMN_NAME` AS `referenced_column_name`\nFROM `information_schema`.`REFERENTIAL_CONSTRAINTS` AS `rc`\nJOIN `information_schema`.`KEY_COLUMN_USAGE` AS `kcu` ON\n    (\n        `kcu`.`CONSTRAINT_CATALOG` = `rc`.`CONSTRAINT_CATALOG` OR\n        (`kcu`.`CONSTRAINT_CATALOG` IS NULL AND `rc`.`CONSTRAINT_CATALOG` IS NULL)\n    ) AND\n    `kcu`.`CONSTRAINT_SCHEMA` = `rc`.`CONSTRAINT_SCHEMA` AND\n    `kcu`.`CONSTRAINT_NAME` = `rc`.`CONSTRAINT_NAME`\nWHERE `rc`.`CONSTRAINT_SCHEMA` = database() AND `kcu`.`TABLE_SCHEMA` = database()\nAND `rc`.`TABLE_NAME` = 'audit_entry' AND `kcu`.`TABLE_NAME` = 'audit_entry'"],"dst":"mysql:host=uat..fr;port=3306;dbname=sid-uat","name":"yii\\db\\Command::queryInternal","stp":"2101"},{"E":12031,"S":206,"calls":[{"E":185,"S":210,"calls":[{"E":18,"EXP":"Redis error: ERR This instance has cluster support disabled\nRedis command was: CLUSTER INFO","S":221,"calls":[{"E":15,"S":221,"calls":[{"E":2,"S":234,"calls":[{"E":0,"S":234,"name":"yii\\redis\\Connection::open"},{"E":2,"S":234,"name":"yii\\redis\\Connection::sendCommandInternal","stp":"1501"}],"clues":["-1:SELECT 3"],"name":"yii\\redis\\Connection::executeCommand","stp":"1501"}],"dst":"tcp://uat.fr:6379, database=3","name":"yii\\redis\\Connection::open","stp":"8200"},{"E":3,"EXP":"Redis error: ERR This instance has cluster support disabled\nRedis command was: CLUSTER INFO","S":236,"name":"yii\\redis\\Connection::sendCommandInternal","stp":"1501"}],"clues":["-1:CLUSTER INFO "],"name":"yii\\redis\\Connect
  | [pinpoint] [1] [1]agent try to connect:(tcp:pinpoint-collector-agent:8181)
  | [pinpoint] [1] [1]#128 pinpoint_end_trace Done!
```

On collector agent which is `pinpoint-collector-agent:8181` v0.4.1, I've got the following:

```
[2021-01-15 11:54:17,683] [30] [INFO] [StreamServerLayer.py:141] new connect fd:8
[2021-01-15 11:54:17,683] [30] [DEBUG] [FrontAgent.py:90] send hello:8 len:59
[2021-01-15 11:54:17,684] [30] [DEBUG] [StreamServerLayer.py:97] send 59
[2021-01-15 11:54:17,704] [30] [WARNING] [StreamServerLayer.py:68] peer error:[Errno 104] Connection reset by peer
[2021-01-15 11:54:17,705] [30] [WARNING] [StreamServerLayer.py:168]  client:8 disconnected
[2021-01-15 11:54:17,705] [30] [DEBUG] [StreamServerLayer.py:74] close client:8(('10.131.0.1', 51576))
```

And not trace is sent to the UI.


Discussion / hints:
When I'm adding a sleep after the run of the php command in the cronjob, the message become the following:

```
[2021-01-15 12:28:24,806] [30] [INFO] [StreamServerLayer.py:141] new connect fd:8
[2021-01-15 12:28:24,814] [30] [DEBUG] [FrontAgent.py:90] send hello:8 len:59
[2021-01-15 12:28:24,814] [30] [WARNING] [StreamServerLayer.py:63] peer close socket
[2021-01-15 12:28:24,814] [30] [WARNING] [StreamServerLayer.py:168]  client:8 disconnected
[2021-01-15 12:28:24,814] [30] [DEBUG] [StreamServerLayer.py:74] close client:8(('10.131.0.1', 45766))
```

No more reset but still no trace in UI.

@marty-macfly 
It looks like  the php process was stopped without send all span.

Please share more detail about how does your "cron jop" works. 
it's a [kubernetes cron job](https://kubernetes.io/docs/concepts/workloads/controllers/cron-jobs/) at the given time a container will be startup running the given command line here it's `php yii ....` the job run and at the end of the run of the php cli run, the container is removed. Collector agent is in another container and always running and listening on port 8080 for trace.
> It works in our env without changing everything. 

But, you can 

## Try this

> pinpoint_php.SendSpanTimeOutMs= 100 # send span with timeout 100ms

![image](https://user-images.githubusercontent.com/27064129/104978683-65a8d380-5a3d-11eb-97a5-0e3bc6ad2ab3.png)

Does it mean it will send a span every 100ms ? So if I enable report I should see something like that:

```
agent try to connect:(tcp:pinpoint-collector-agent:8181)
#128 pinpoint_end_trace Done!
```
Every 100ms ?
> Does it mean it will send a span every 100ms ? So if I enable report I should see something like that:
> 
> ```
> agent try to connect:(tcp:pinpoint-collector-agent:8181)
> #128 pinpoint_end_trace Done!
> ```
> 
> Every 100ms ?


First, does it meet your requirement?
Then, NO. 100ms is time for the waiting_event timeout.

Doesn't change anything still same output of the report and the reset message on collector agent log.
I found your container  will be removed every time. Sorry to tell you, current agent can't support. 

Before supporting this feature, there are some issues need your help

1. does the script running in a new container  every time? if not agent could go to normal at next time.

@marty-macfly 

Agent is in a dedicated container which is always running that why I'm not using socket in that case but tcp:port. So agent always running and listening on port 8181.

The cli with the php pinpoint extension is running in a container which is created and destroy every-time and is sending data to agent through tcp on port 8181.
> Agent is in a dedicated container which is always running that why I'm not using socket in that case but tcp:port. So agent always running and listening on port 8181.
> 
> The cli with the php pinpoint extension is running in a container which is created and destroy every-time and is sending data to agent through tcp on port 8181.


For your description， the collector-agent is OK.
 The plugins and pinpoint extension not support this feature.

Thank your feedback. 

Just a recap of our current setup:

* PHP CLI + pinpoint-php-module running in a container that is created and destroy it time the Kubernetes cron job trigger it.

`php.ini` configuration for pinpoint-php-module

```ini
extension=pinpoint_php.so
pinpoint_php.CollectorHost=tcp:pinpoint-collector-agent:8181
pinpoint_php.SendSpanTimeOutMs=100
pinpoint_php.TraceLimit=-1 
```

* Container running [pinpoint python collector agent](https://github.com/pinpoint-apm/pinpoint-c-agent/blob/master/DOC/CollectorAgent/Readme.md) as a daemon refered in previous configuration as `pinpoint-collector-agent:8181`.

Configuration of collector agent is the following:

```ini
[Collector]
ServerType=1500
collector.grpc.agent.ip=pinpoint-collector.pinpoint-uat.svc
collector.grpc.agent.port=9991
collector.grpc.stat.ip=pinpoint-collector.pinpoint-uat.svc
collector.grpc.stat.port=9992
collector.grpc.span.ip=pinpoint-collector.pinpoint-uat.svc
collector.grpc.span.port=9993
collector.grpc.discardpolicy.maxpendingthreshold=10000

[Common]
# Apache webserver port
Web_Port=8080
Log_Level=INFO
LOG_DIR=/var/log/pinpoint-collector-agent

[Agent]
Address=0.0.0.0@8181
```

* [Pinpoint platform](http://pinpoint-apm.github.io/pinpoint/overview.html#architecture) running Web UI, Java pinpoint collector services previously refereed in python collector agent as `pinpoint-collector.pinpoint-uat.svc` on port 9991, 9992, 9993, ...

So if I understand properly in that setup it's  `pinpoint-php-module` that doesn't support it ? Did I properly understood ? Thanks for your help and support.
I'm updating that issue because I've found the following. We've seen that some run were not working as explain in previous comment here. But some use case were working for example in case of CLI running on the same container as the php-fpm process. Or when I've got long running CLI (workers). In both case I was using the agent version 0.4.2 in python with php extension sending data through unix socket.

We've update the agent to the Go version of the agent and some use case that was working before are not working anymore. For example long running CLI and CLI run inside the php-fpm container. Difference is we are now using tcp connection to send data from the PHP extension to the GO agent because Go agent is not supporting socket.

After some investigation I've seen the following when testing on my local laptop CLI tracing are still working but when testing on test environment where agent and PHP extension are on different host it's not working anymore but php-fpm tracing work. when I'm running CLI in debug I've seen the following difference from local and test env on loca:

CLI debug report is:

```
[pinpoint] [72] [72]this span:(....)
[pinpoint] [72] [72]agent try to connect:(tcp:192.168.254.1:8088)
[pinpoint] [72] [72]fd 5 send size 579
[pinpoint] [72] [72]#128 pinpoint_end_trace Done!
```

On test env were agent and CLI is not on the same host trace is the following:

```
[pinpoint] [72] [72]this span:(....)
[pinpoint] [72] [72]agent try to connect:(tcp:192.168.254.1:8088)
[pinpoint] [72] [72]#128 pinpoint_end_trace Done!
```
We can see that we don't have the `fd...` debug message, I've put some more debug in the php extension and I've found that the [`TransLayer::trans_layer_pool()`](https://github.com/pinpoint-apm/pinpoint-c-agent/blob/master/common/src/ConnectionPool/TransLayer.cpp#L128) is going into [`else` statement](https://github.com/pinpoint-apm/pinpoint-c-agent/blob/master/common/src/ConnectionPool/TransLayer.cpp#L187) which is comment with `timeout do nothing`

[`int retval = select(fd+1,&rfds,&wfds,&efds,&tv);`](https://github.com/pinpoint-apm/pinpoint-c-agent/blob/master/common/src/ConnectionPool/TransLayer.cpp#L162) so the return value of the select is 0, I've check the documentation of [`select`](https://man7.org/linux/man-pages/man2/select.2.html)

So select behavior is based on [timeout](https://github.com/pinpoint-apm/pinpoint-c-agent/blob/master/common/src/ConnectionPool/TransLayer.cpp#L160) the doc is saying the following 

> The timeout argument is a timeval structure (shown below) that specifies the interval that select() should block waiting for a file descriptor to become ready.
> ...
> If both fields of the timeval structure are zero, then select() returns immediately.  (This is useful for polling.)

In our case timeout is define as follow:

```C
struct timeval tv = {0,(int)timeout *1000};
```

So I add more debug and in fact `timeout` is `NULL` so both fields are 0 so select is not waiting and returns immediately. If I hardcode the timeval with `struct timeval tv = {5,(int)timeout *1000};` select will wait for maximum 5 seconds and after timeout.

In that case my trace is properly send and my debug report for CLI on local and on test env is the same. In your first comment you said to set `pinpoint_php.SendSpanTimeOutMs = 100`  which seems to be the proper solution to make things work but when I've search into the code I don't see any declaration of that configuration element in the php ini entry list [STD_PHP_INI_ENTRY](https://github.com/pinpoint-apm/pinpoint-c-agent/blob/master/src/PHP/pinpoint_php.cpp#L83) and anywhere in the code so I'm wondering if that directive still usable ?

Fix patch:
diff --git a/common/src/ConnectionPool/SpanConnectionPool.cpp b/common/src/ConnectionPool/SpanConnectionPool.cpp
index 99c322818..32240f98e 100644
--- a/common/src/ConnectionPool/SpanConnectionPool.cpp
+++ b/common/src/ConnectionPool/SpanConnectionPool.cpp
@@ -27,9 +27,8 @@
 namespace ConnectionPool {
 using Cache::SafeSharedState;
 
-SpanConnectionPool::SpanConnectionPool(const char* co_host,uint32_t w_timeout_ms):
+SpanConnectionPool::SpanConnectionPool(const char* co_host):
         co_host(co_host),
-        timeout_ms(w_timeout_ms),
         con_counter(0)
 {
     this->_cPool.push(this->createTrans());
diff --git a/common/src/ConnectionPool/SpanConnectionPool.h b/common/src/ConnectionPool/SpanConnectionPool.h
index 193fd4c00..5d142ce1a 100644
--- a/common/src/ConnectionPool/SpanConnectionPool.h
+++ b/common/src/ConnectionPool/SpanConnectionPool.h
@@ -43,17 +43,15 @@ class SpanConnectionPool
     SpanConnectionPool& operator=(SpanConnectionPool&&) =delete;
 
 public:
-    SpanConnectionPool(const char* co_host,uint32_t w_timeout_ms);
+    SpanConnectionPool(const char* co_host);
     //for delay initialization
     SpanConnectionPool(){
-        this->timeout_ms = 0;
         this->con_counter = 0;
     };
 
-    void initPool(const char* co_host,uint32_t w_timeout_ms)
+    void initPool(const char* co_host)
     {
         this->co_host = co_host;
-        this->timeout_ms = w_timeout_ms;
         this->_cPool.push(this->createTrans());
     }
 
@@ -88,7 +86,6 @@ class SpanConnectionPool
     // void _handleTransLayerState(int state);
 private:
     std::string co_host;
-    uint32_t timeout_ms;
     uint32_t con_counter;
     std::stack<TransConnection> _cPool;
     std::mutex _lock;
diff --git a/common/src/Util/Helper.cpp b/common/src/Util/Helper.cpp
index 808b01379..c4211519b 100644
--- a/common/src/Util/Helper.cpp
+++ b/common/src/Util/Helper.cpp
@@ -83,7 +83,7 @@ TransConnection getConnection()
 {
     
     std::call_once (_pool_init_flag,
-        [](){_con_pool.initPool(global_agent_info.co_host,global_agent_info.timeout_ms);}
+        [](){_con_pool.initPool(global_agent_info.co_host);}
     );
 
     return _con_pool.get();
@@ -93,7 +93,7 @@ void freeConnection(TransConnection& trans)
 {
   
     std::call_once (_pool_init_flag,
-        [](){_con_pool.initPool(global_agent_info.co_host,global_agent_info.timeout_ms);}
+        [](){_con_pool.initPool(global_agent_info.co_host);}
     );
     
     return _con_pool.free(trans);
diff --git a/common/src/common.cpp b/common/src/common.cpp
index 9f5aaaaa3..26cf9243e 100644
--- a/common/src/common.cpp
+++ b/common/src/common.cpp
@@ -44,8 +44,7 @@ static NodeID do_end_trace(TraceNode&);
 
 static thread_local NodeID __tls_id = 0;
 // send current span with timeout
-static const int SPAN_TIMEOUT_MS=0;
-static thread_local int _span_timeout = SPAN_TIMEOUT_MS;
+static thread_local int _span_timeout = global_agent_info.timeout_ms;
 
 NodeID pinpoint_get_per_thread_id()
 {
@@ -57,7 +56,6 @@ void pinpoint_update_per_thread_id(NodeID id)
     __tls_id = id;
 }
 
-
 static NodeID do_start_trace(NodeID& _id)
 {
     uint64_t time_in_ms = Helper::get_current_msec_stamp();
@@ -186,7 +184,8 @@ int pinpoint_force_end_trace(NodeID id,int32_t timeout)
         while(id != 0){
             id = pinpoint_end_trace(id);
         }
-        _span_timeout = SPAN_TIMEOUT_MS;
+        //back to normal
+        _span_timeout = global_agent_info.timeout_ms;
         return 0;
     }catch(const std::out_of_range&){
         pp_trace("#%d not found",id);
diff --git a/src/PHP/php_pinpoint_php.h b/src/PHP/php_pinpoint_php.h
index 8798d1290..2d8bd481d 100644
--- a/src/PHP/php_pinpoint_php.h
+++ b/src/PHP/php_pinpoint_php.h
@@ -38,7 +38,7 @@ extern zend_module_entry pinpoint_php_module_entry;
 #endif
 
 ZEND_BEGIN_MODULE_GLOBALS(pinpoint_php)
-//    uint  w_timeout_ms;
+    uint  w_timeout_ms;
     char*  co_host; // tcp:ip:port should support dns
     zend_bool   utest_flag;
 //    zend_bool   limit;
diff --git a/src/PHP/pinpoint_php.cpp b/src/PHP/pinpoint_php.cpp
index 3b808751c..cffa81a52 100644
--- a/src/PHP/pinpoint_php.cpp
+++ b/src/PHP/pinpoint_php.cpp
@@ -80,6 +80,10 @@ static void pinpoint_log(char *msg);
 
 PHP_INI_BEGIN()
 
+
+STD_PHP_INI_ENTRY("pinpoint_php.SendSpanTimeOutMs", "0", PHP_INI_ALL,
+        OnUpdateLong,w_timeout_ms,zend_pinpoint_php_globals,pinpoint_php_globals)
+
 STD_PHP_INI_ENTRY("pinpoint_php.CollectorHost", "unix:/tmp/collector.sock", PHP_INI_ALL,
         OnUpdateString,co_host,zend_pinpoint_php_globals,pinpoint_php_globals)
 
@@ -642,6 +646,7 @@ PHP_MINIT_FUNCTION(pinpoint_php)
     // global_agent_info.
     strncpy(global_agent_info.co_host ,PPG(co_host),MAX_ADDRESS_SIZE);
     global_agent_info.inter_flag = PPG(debug_report);
+    global_agent_info.timeout_ms = PPG(w_timeout_ms);
     global_agent_info.trace_limit =PPG(tracelimit);
     global_agent_info.agent_type = 1500; // PHP
 


Test patch:
diff --git a/common/test/test_trans_layer.cc b/common/test/test_trans_layer.cc
index d5f50df0e..4dad65de0 100644
--- a/common/test/test_trans_layer.cc
+++ b/common/test/test_trans_layer.cc
@@ -121,7 +121,7 @@ TEST(translayer, stream_socket_layer)
 TEST(ConnectionPool, API)
 {
     std::string remote = global_agent_info.co_host;
-    SpanConnectionPool _pool(remote.c_str(),10);
+    SpanConnectionPool _pool(remote.c_str());
 
     // SpanConnectionPool _pool1 = _pool;
     // (void)_pool1;