anhnongdan commented 7 years ago

PW5 queuetracking plugin works as normal but no log is imported (log_visit is empty).
Redis queue shows the normal log queue => Queued tracking is working normally. [root@VNPT-HNI-ANALYTIC-03 bimax]# ./flow.sh monitor 5 Queue is enabled Request sets in the queue will be processed automatically after a tracking request Up to 32 workers will be used Processor will start once there are at least 1 request sets in the queue 22 (1+2+0+0+0+1+0+0+0+1+1+2+0+0+1+1+0+0+2+3+0+1+1+1+0+1+0+1+0+0+2+0) request sets left in queue. 1.01M used memory (1.21M peak). 5 wo7 (0+1+0+0+0+0+0+0+0+0+0+0+0+0+0+1+0+0+0+1+0+1+0+0+0+1+0+1+0+0+1+0) request sets left in queue. 917.48K used memory (1.21M peak). 5 w10 (0+0+1+0+0+0+0+0+0+0+1+0+0+0+1+2+0+0+0+0+1+1+0+1+0+0+0+1+0+0+0+1) request sets left in queue. 995.84K used memory (1.21M peak). 5 11 (1+1+0+0+2+1+0+1+0+0+2+0+0+1+0+0+0+0+0+0+1+0+0+0+0+1+0+0+0+0+0+0) request sets left in queue. 963.91K used memory (1.21M peak). 5 workers active.

!! Piwik warns about the config file: The Piwik configuration file (config/config.ini.php) is not writable, some of your changes might not be saved. Please change permissions of the config file to make it writable.

anhnongdan commented 7 years ago

pw.log file shows no abnormally.

anhnongdan commented 7 years ago

checked mysql db processlist, there're processes but might be the archive processes: | 1775368 | admin | localhost:52372 | pw5 | Sleep | 0 | | NULL | 0.000 | | 1775378 | admin | localhost:53600 | pw5 | Sleep | 1 | | NULL | 0.000 | | 1775379 | admin | localhost:53602 | pw5 | Sleep | 4 | | NULL | 0.000 | | 1775394 | admin | localhost:54236 | pw5 | Query | 0 | preparing | SELECT visit_last_action_time, visit_first_action_time, idvisitor, idvisit, user_id, visit_exit_idac | 0.000 |

Action tracker empty: select count(*) from piwik_log_link_visit_action_tracker;

anhnongdan commented 7 years ago

Monitor Redis. It seems that redis queue of pw5 works normally, RPUSH value correctly.

?? Some time the queue is idle for a while.

=> Enabled imports_log logging:

Configure logging before calling logging.{debug,info}.

    logging.basicConfig(
        #filename='/tmp/imports_log.log',
        format='%(asctime)s: [%(levelname)s] %(message)s',
        level=logging.DEBUG if self.options.debug >= 1 else logging.INFO,
    )

But Everything seems to be OK. 2017-05-30 15:18:13,320: [DEBUG] [{"idsite":"5011"}] 2017-05-30 15:18:13,320: [DEBUG] Site ID for hostname static.easyvideo.vn: 5011 2017-05-30 15:18:13,321: [DEBUG] [{"idsite":"5011"}] 2017-05-30 15:18:13,321: [DEBUG] hit.extension: css 2017-05-30 15:18:13,321: [DEBUG] Site ID for hostname static.easyvideo.vn: 5011 2017-05-30 15:18:13,321: [DEBUG] hit.extension: css 2017-05-30 15:18:13,321: [DEBUG] hit.extension: css 2017-05-30 15:18:13,322: [DEBUG] hit.extension: json 2017-05-30 15:18:13,322: [DEBUG] hit.extension: css 2017-05-30 15:18:13,322: [DEBUG] hit.extension: css 2017-05-30 15:18:13,323: [DEBUG] <urllib2.Request instance at 0x10ad0e0> 2017-05-30 15:18:13,323: [DEBUG] hit.extension: json 2017-05-30 15:18:13,324: [DEBUG] <urllib2.Request instance at 0x10ada28> 2017-05-30 15:18:13,324: [DEBUG] [{"idsite":"5011"}] 2017-05-30 15:18:13,325: [DEBUG] Site ID for hostname static.easyvideo.vn: 5011 2017-05-30 15:18:13,325: [DEBUG] hit.extension: css 2017-05-30 15:18:13,325: [DEBUG] hit.extension: ttf 2017-05-30 15:18:13,325: [DEBUG] hit.extension: json

anhnongdan commented 7 years ago

Try with console queuetracking:

[root@VNPT-HNI-ANALYTIC-03 bimax]# ./flow.sh r pw5 /usr/share/nginx/www/console queuedtracking:process Starting to process request sets, this can take a while

This worker finished queue processing with 0req/s (0 requests in 7.92 seconds)

anhnongdan commented 7 years ago

The chance to reproduce the problem on server is slim. Use local environment on my machine.

anhnongdan commented 7 years ago

Checking on cBimax: #v3_clean

On local host, log_importing: https://github.com/anhnongdan/bimax_analytics/tree/new

anhnongdan commented 7 years ago

cBimax @v3clean:

!! Attention: import_logs.py only work with Python 2.x, python 3 not yet support.

Now, parsing OK but no log imported => continue to debug.

anhnongdan commented 7 years ago

Check action_tracker: no log import

-> no error in piwik log, no error in import_log log, no error nginx access log and error log

-> remove --recorders=32 in piwik_pipe.sh -> seem to work -> show SQL error of missing bandwidth column IN NGINX ERROR LOG.

=> drop tracker table and recreate => import log work 500 lines parsed, 100 lines recorded, 1 records/sec (avg), 0 records/sec (current)

anhnongdan commented 7 years ago

++

Logs import summary

600 requests imported successfully
2 requests were downloads
0 requests ignored:
    0 HTTP errors
    0 HTTP redirects
    0 invalid log lines
    0 requests did not match any known site
    0 requests did not match any --hostname
    0 requests done by bots, search engines...
    0 requests to static resources (css, js, images, ico, ttf...)
    0 requests to file downloads did not match any --download-extensions

Website import summary

600 requests imported to 1 sites
    1 sites already existed
    0 sites were created:

0 distinct hostnames did not match any existing site:

Performance summary

Total time: 123 seconds
Requests imported per second: 4.87 requests per second

anhnongdan commented 7 years ago

insert piwik_log_link_visit_action select * from piwik_log_link_visit_action_tracker; truncate table piwik_log_link_visit_action_tracker;

Nothing show on all CDNs before running archive() -> run archive: ./console core:archive --force-periods=day --force-date-range="2017-05-31,2017-05-31"

-> Error: no location_provider in log_visit alter table piwik_log_visit add location_provider varchar(200) null;

=> correct calc: 59 visits, 598 hits, 602 actions

Now continue on Server

anhnongdan commented 7 years ago

On Viettel Server: import log go through QueuedTracking and is not working.

Nothing weird in pw.log db processlist show no process

/data/app/bimax/flow.sh r redis5_ redis-cli -p 6005 redis monitor show input data as normal

=> so, the problem might be in the import_log or piwik_pipe => it's seem that piwik push everything (log coming) to redis queue, may be fail to process when pop it out but no log output.

anhnongdan commented 7 years ago

queuedtracking test:

root@VT-HNI-BIMAX-01:/data/bimax/pw5/www$ /data/app/bimax/flow.sh r pw5_ php /usr/share/nginx/www/console queuedtracking:test
PHPRedis version: 2.2.8-devphp7
Settings that will be used:
Host: 127.0.0.1
Port: 6005
Timeout: 0
Password: 
Database: 0
NumQueueWorkers: 32
NumRequestsToProcess: 1
ProcessDuringTrackingRequest: 1
QueueEnabled: 1
UseSentinelBackend: 0
SentinelMasterName: mymaster

Version / stats:
PHP version: 7.0.13-0ubuntu0.16.04.1
Uname: Linux VT-HNI-BIMAX-01 3.10.0-514.6.1.el7.x86_64 #1 SMP Wed Jan 18 13:06:36 UTC 2017 x86_64
Redis version: 3.0.6
Memory: array (
  'used_memory' => 814848,
  'used_memory_human' => '795.75K',
  'used_memory_rss' => 6565888,
  'used_memory_peak' => 2101600,
  'used_memory_peak_human' => '2.00M',
  'used_memory_lua' => 33792,
  'mem_fragmentation_ratio' => '8.06',
  'mem_allocator' => 'jemalloc-3.6.0',
)
MaxMemory Eviction Policy config: noeviction
MaxMemory config: 0

Performing some tests:
Redis is connected: 1
Connection works in general
Success for method set(testKey, value)
Success for method setnx(testnxkey, value)
Success for method setex(testexkey, 5, value)
Success for method set(testKeyWithNx, value, Array)
Success for method set(testKeyWithEx, value, Array)
Initial expire seems to be set correctly
setIfNotExists works fine
expireIfKeyHasValue seems to work fine
Extending expire seems to be set correctly
expireIfKeyHasValue correctly expires only when the value is correct
Expire is still set which is correct
deleteIfKeyHasValue seems to work fine
List feature seems to not work fine: 

Done

Problem here is List feature doesn't work fine, that works fine on other instance of Piwik!!!

anhnongdan commented 7 years ago

Turn out that php hhvm is running: hhvm --help of course php-fpm is also running,

-> sv stop hhvm in the container. Error pop out: The directory "/usr/share/nginx/www/tmp/cache/tracker/" does not exist and could not be created.

=> Solve permission. Still has problem.

List feature seems to not work fine: still remains

anhnongdan commented 7 years ago

Run queuedTracking:test on local - redis on docker: same problem

tony@tony-local:~/Git/cBIMAX/src$ ./console queuedtracking:test
PHPRedis version: 3.1.2
Settings that will be used:
Host: 127.0.0.1
Port: 6379
Timeout: 0
Password: 
Database: 0
NumQueueWorkers: 32
NumRequestsToProcess: 1
ProcessDuringTrackingRequest: 1
QueueEnabled: 1
UseSentinelBackend: 0
SentinelMasterName: mymaster

Version / stats:
PHP version: 5.6.30-7+deb.sury.org~xenial+1
Uname: Linux tony-local 4.4.0-66-generic #87-Ubuntu SMP Fri Mar 3 15:29:05 UTC 2017 x86_64
Redis version: 3.2.8
Memory: array (
  'used_memory' => 820368,
  'used_memory_human' => '801.14K',
  'used_memory_rss' => 9543680,
  'used_memory_rss_human' => '9.10M',
  'used_memory_peak' => 821392,
  'used_memory_peak_human' => '802.14K',
  'total_system_memory' => 8224509952,
  'total_system_memory_human' => '7.66G',
  'used_memory_lua' => 37888,
  'used_memory_lua_human' => '37.00K',
  'maxmemory' => 0,
  'maxmemory_human' => '0B',
  'maxmemory_policy' => 'noeviction',
  'mem_fragmentation_ratio' => 11.630000000000001,
  'mem_allocator' => 'jemalloc-4.0.3',
)
MaxMemory Eviction Policy config: noeviction
MaxMemory config: 0

Performing some tests:
Redis is connected: 1
Connection works in general
Success for method set(testKey, value)
Success for method setnx(testnxkey, value)
Success for method setex(testexkey, 5, value)
Success for method set(testKeyWithNx, value, Array)
Success for method set(testKeyWithEx, value, Array)
Initial expire seems to be set correctly
setIfNotExists works fine
expireIfKeyHasValue seems to work fine
Extending expire seems to be set correctly
expireIfKeyHasValue correctly expires only when the value is correct
Expire is still set which is correct
deleteIfKeyHasValue seems to work fine
List feature seems to not work fine: 

Done

anhnongdan commented 7 years ago

Typical Piwik redis call when run queuedTracking:monitor

1498138019.460711 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_28"
1498138019.460967 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_29"
1498138019.461222 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_30"
1498138019.461466 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_31"
1498138019.461809 [0 172.18.0.1:58916] "KEYS" "QueuedTrackingLock*"
1498138021.462519 [0 172.18.0.1:58916] "INFO" "memory"
1498138021.463001 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1"
1498138021.463243 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_1"
1498138021.463496 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_2"
1498138021.463744 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_3"
1498138021.463977 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_4"
1498138021.464203 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_5"
1498138021.464521 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_6"
1498138021.464800 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_7"
1498138021.465054 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_8"
1498138021.465325 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_9"
1498138021.465522 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_10"
1498138021.465758 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_11"
1498138021.465994 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_12"
1498138021.466238 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_13"
1498138021.466470 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_14"
1498138021.466693 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_15"
1498138021.466909 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_16"
1498138021.467119 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_17"
1498138021.467314 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_18"
1498138021.467513 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_19"
1498138021.467735 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_20"
1498138021.467992 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_21"
1498138021.468147 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_22"
1498138021.468331 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_23"
1498138021.468479 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_24"
1498138021.468664 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_25"
1498138021.468846 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_26"
1498138021.469050 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_27"
1498138021.469249 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_28"
1498138021.469445 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_29"
1498138021.469631 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_30"
1498138021.469846 [0 172.18.0.1:58916] "LLEN" "trackingQueueV1_31"
1498138021.470037 [0 172.18.0.1:58916] "KEYS" "QueuedTrackingLock*"

anhnongdan commented 7 years ago

Problem show on local -> problem of Redis, no error log in Piwik log, no nginx error, just some 500 lines in access log

2017-06-22 20:29:35,824: [INFO] Error when connecting to Piwik: HTTP Error 500: Internal Server Error
2017-06-22 20:29:35,825: [INFO] Max number of attempts reached, server is unreachable!
Fatal error: HTTP Error 500 Internal Server Error, response: <br />
<b>Fatal error</b>:  Class 'Redis' not found in <b>/home/tony/Git/cBIMAX/plugins/QueuedTracking/Queue/Backend/Redis.php</b> on line <b>236</b><br />

You can restart the import of "(stdin)" from the point it failed by specifying --skip=0 on the command line.

Access log:

127.0.0.1 - - [22/Jun/2017:20:29:15 +0700] "POST /cBIMAX/src/ HTTP/1.1" 200 27 "-" "Piwik/LogImport" 127.0.0.1 - - [22/Jun/2017:20:29:15 +0700] "POST /cBIMAX/src/piwik.php HTTP/1.1" 500 167 "-" "Piwik/LogImport" 127.0.0.1 - - [22/Jun/2017:20:29:25 +0700] "POST /cBIMAX/src/piwik.php HTTP/1.1" 500 167 "-" "Piwik/LogImport" 127.0.0.1 - - [22/Jun/2017:20:29:35 +0700] "POST /cBIMAX/src/piwik.php HTTP/1.1" 500 167 "-" "Piwik/LogImport"

anhnongdan commented 7 years ago

When success with Redis, importing ratio improved significantly. Some error returned. (finally 700/900) redis feature list still fails

tony@tony-local:~/Git/bimax_analytics$ cat %log/live.csmtalk.vcdn.vn_2017_05_31_14_00 | ./scribe_pipe.13
0 lines parsed, 0 lines recorded, 0 records/sec (avg), 0 records/sec (current)
Parsing log (stdin)...
256 lines parsed, 0 lines recorded, 0 records/sec (avg), 0 records/sec (current)
400 lines parsed, 0 lines recorded, 0 records/sec (avg), 0 records/sec (current)
400 lines parsed, 0 lines recorded, 0 records/sec (avg), 0 records/sec (current)
400 lines parsed, 0 lines recorded, 0 records/sec (avg), 0 records/sec (current)
2017-06-22 21:16:04,445: [INFO] bulk tracking returned invalid JSON
2017-06-22 21:16:04,446: [INFO] tracker response:
GIF89a�!�,D;
500 lines parsed, 100 lines recorded, 19 records/sec (avg), 100 records/sec (current)
500 lines parsed, 100 lines recorded, 16 records/sec (avg), 0 records/sec (current)
2017-06-22 21:16:06,497: [INFO] bulk tracking returned invalid JSON
2017-06-22 21:16:06,498: [INFO] tracker response:
GIF89a�!�,D;
600 lines parsed, 200 lines recorded, 28 records/sec (avg), 100 records/sec (current)
600 lines parsed, 200 lines recorded, 24 records/sec (avg), 0 records/sec (current)
600 lines parsed, 200 lines recorded, 22 records/sec (avg), 0 records/sec (current)
2017-06-22 21:16:08,787: [INFO] bulk tracking returned invalid JSON
2017-06-22 21:16:08,787: [INFO] tracker response:
GIF89a�!�,D;
700 lines parsed, 300 lines recorded, 29 records/sec (avg), 100 records/sec (current)
700 lines parsed, 300 lines recorded, 27 records/sec (avg), 0 records/sec (current)

Redis Monitor on Local

1498140978.652258 [0 172.18.0.1:60496] "RPUSH" "trackingQueueV1_8" "{\"requests\":[{\"apiv\":\"1\",\"url\":\"http:\\/\\/live.csmtalk.vcdn.vn\\/hls\\/$tk$\\/\\/15c594a5cff\\/xemtivinet\\/chunklist.m3u8\",\"cvar\":\"{\\\"1\\\": [\\\"HTTP-code\\\", \\\"410\\\"]}\",\"action_name\":\"410\\/URL = http%3A%2F%2Flive.csmtalk.vcdn.vn%2Fhls%2F%24tk%24%2F%2F15c594a5cff%2Fxemtivinet%2Fchunklist.m3u8\",\"cdt\":\"2017-05-31 07:00:27\",\"cip\":\"123.26.190.40\",\"urlref\":\"\",\"bw_bytes\":158,\"rec\":\"1\",\"_cvar\":\"{\\\"1\\\": [\\\"Not-Bot\\\", \\\"Allwinner\\/CedarX 2.6\\\"]}\",\"idsite\":\"3\",\"bots\":\"1\",\"ua\":\"Allwinner\\/CedarX 2.6\",\"gt_ms\":13,\"dp\":\"1\"}],\"env\":{\"server\":{\"USER\":\"tony\",\"HOME\":\"\\/home\\/tony\",\"FCGI_ROLE\":\"RESPONDER\",\"PATH_INFO\":\"\",\"SCRIPT_FILENAME\":\"\\/home\\/tony\\/www\\/cBIMAX\\/src\\/piwik.php\",\"QUERY_STRING\":\"\",\"REQUEST_METHOD\":\"POST\",\"CONTENT_TYPE\":\"application\\/json\",\"CONTENT_LENGTH\":\"55731\",\"SCRIPT_NAME\":\"\\/cBIMAX\\/src\\/piwik.php\",\"REQUEST_URI\":\"\\/cBIMAX\\/src\\/piwik.php\",\"DOCUMENT_URI\":\"\\/cBIMAX\\/src\\/piwik.php\",\"DOCUMENT_ROOT\":\"\\/home\\/tony\\/www\",\"SERVER_PROTOCOL\":\"HTTP\\/1.1\",\"REQUEST_SCHEME\":\"http\",\"GATEWAY_INTERFACE\":\"CGI\\/1.1\",\"SERVER_SOFTWARE\":\"nginx\\/1.10.0\",\"REMOTE_ADDR\":\"127.0.0.1\",\"REMOTE_PORT\":\"49112\",\"SERVER_ADDR\":\"127.0.0.1\",\"SERVER_PORT\":\"80\",\"SERVER_NAME\":\"127.0.0.1\",\"REDIRECT_STATUS\":\"200\",\"HTTP_ACCEPT_ENCODING\":\"identity\",\"HTTP_CONTENT_LENGTH\":\"55731\",\"HTTP_HOST\":\"localhost\",\"HTTP_CONTENT_TYPE\":\"application\\/json\",\"HTTP_CONNECTION\":\"close\",\"HTTP_USER_AGENT\":\"Piwik\\/LogImport\",\"PHP_SELF\":\"\\/cBIMAX\\/src\\/piwik.php\",\"REQUEST_TIME_FLOAT\":1498140978.5635,\"REQUEST_TIME\":1498140978}},\"tokenAuth\":\"e750e87a0c9ee759f7dc97366a6ff61a\",\"time\":1498140978}"
1498140978.652605 [0 172.18.0.1:60496] "RPUSH" "trackingQueueV1_20" "{\"requests\":[{\"apiv\":\"1\",\"url\":\"http:\\/\\/live.csmtalk.vcdn.vn\\/hls\\/$tk$\\/\\/15c4d837ae9\\/xembongtvr\\/chunklist.m3u8\",\"cvar\":\"{\\\"1\\\": [\\\"HTTP-code\\\", \\\"410\\\"]}\",\"action_name\":\"410\\/URL = http%3A%2F%2Flive.csmtalk.vcdn.vn%2Fhls%2F%24tk%24%2F%2F15c4d837ae9%2Fxembongtvr%2Fchunklist.m3u8\",\"cdt\":\"2017-05-31 07:00:23\",\"cip\":\"101.14.91.8\",\"urlref\":\"\",\"bw_bytes\":560,\"rec\":\"1\",\"_cvar\":\"{\\\"1\\\": [\\\"Not-Bot\\\", \\\"Mozilla\\/5.0 (Linux; Android 6.0.1; SM-G610Y Build\\/MMB29K; wv) AppleWebKit\\/537.36 (KHTML, like Gecko) Version\\/4.0 Chrome\\/55.0.2883.91 Mobile Safari\\/537.36\\\"]}\",\"idsite\":\"3\",\"bots\":\"1\",\"ua\":\"Mozilla\\/5.0 (Linux; Android 6.0.1; SM-G610Y Build\\/MMB29K; wv) AppleWebKit\\/537.36 (KHTML, like Gecko) Version\\/4.0 Chrome\\/55.0.2883.91 Mobile Safari\\/537.36\",\"dp\":\"1\"},{\"apiv\":\"1\",\"url\":\"http:\\/\\/live.csmtalk.vcdn.vn\\/hls\\/$tk$\\/\\/15c5cdbfe27\\/tructiepgiaitri\\/chunklist.m3u8\",\"cvar\":\"{\\\"1\\\": [\\\"HTTP-code\\\", \\\"200\\\"]}\",\"cdt\":\"2017-05-31 07:00:22\",\"cip\":\"123.20.164.50\",\"urlref\":\"\",\"bw_bytes\":165,\"rec\":\"1\",\"_cvar\":\"{\\\"1\\\": [\\\"Not-Bot\\\", \\\"ExoPlayerDemo\\/3.17.05.29 (Linux;Android 5.1.1) ExoPlayerLib\\/2.3.1\\\"]}\",\"idsite\":\"3\",\"bots\":\"1\",\"ua\":\"ExoPlayerDemo\\/3.17.05.29 (Linux;Android 5.1.1) ExoPlayerLib\\/2.3.1\",\"gt_ms\":2,\"dp\":\"1\"},{\"apiv\":\"1\",\"url\":\"http:\\/\\/live.csmtalk.vcdn.vn\\/hls\\/$tk$\\/\\/15c594a5cff\\/xemtivinet\\/chunklist.m3u8\",\"cvar\":\"{\\\"1\\\": [\\\"HTTP-code\\\", \\\"410\\\"]}\",\"action_name\":\"410\\/URL = http%3A%2F%2Flive.csmtalk.vcdn.vn%2Fhls%2F%24tk%24%2F%2F15c594a5cff%2Fxemtivinet%2Fchunklist.m3u8\",\"cdt\":\"2017-05-31 07:00:25\",\"cip\":\"123.26.190.40\",\"urlref\":\"\",\"bw_bytes\":158,\"rec\":\"1\",\"_cvar\":\"{\\\"1\\\": [\\\"Not-Bot\\\", \\\"Allwinner\\/CedarX 2.6\\\"]}\",\"idsite\":\"3\",\"bots\":\"1\",\"ua\":\"Allwinner\\/CedarX 2.6\",\"gt_ms\":13,\"dp\":\"1\"},{\"apiv\":\"1\",\"url\":\"http:\\/\\/live.csmtalk.vcdn.vn\\/hls\\/$tk$\\/\\/15c5d4525ef\\/nhim_ha_anh\\/chunklist.m3u8\",\"cvar\":\"{\\\"1\\\": [\\\"HTTP-code\\\", \\\"200\\\"]}\",\"cdt\":\"2017-05-31 07:00:23\",\"cip\":\"100.36.166.194\",\"urlref\":\"\",\"bw_bytes\":160,\"rec\":\"1\",\"_cvar\":\"{\\\"1\\\": [\\\"Not-Bot\\\", \\\"Mozilla\\/5.0 (Windows NT 10.0) AppleWebKit\\/537.36 (KHTML, like Gecko) Chrome\\/58.0.3029.110 Safari\\/537.36\\\"]}\",\"idsite\":\"3\",\"bots\":\"1\",\"ua\":\"Mozilla\\/5.0 (Windows NT 10.0) AppleWebKit\\/537.36 (KHTML, like Gecko) Chrome\\/58.0.3029.110 Safari\\/537.36\",\"dp\":\"1\"}],\"env\":{\"server\":{\"USER\":\"tony\",\"HOME\":\"\\/home\\/tony\",\"FCGI_ROLE\":\"RESPONDER\",\"PATH_INFO\":\"\",\"SCRIPT_FILENAME\":\"\\/home\\/tony\\/www\\/cBIMAX\\/src\\/piwik.php\",\"QUERY_STRING\":\"\",\"REQUEST_METHOD\":\"POST\",\"CONTENT_TYPE\":\"application\\/json\",\"CONTENT_LENGTH\":\"55731\",\"SCRIPT_NAME\":\"\\/cBIMAX\\/src\\/piwik.php\",\"REQUEST_URI\":\"\\/cBIMAX\\/src\\/piwik.php\",\"DOCUMENT_URI\":\"\\/cBIMAX\\/src\\/piwik.php\",\"DOCUMENT_ROOT\":\"\\/home\\/tony\\/www\",\"SERVER_PROTOCOL\":\"HTTP\\/1.1\",\"REQUEST_SCHEME\":\"http\",\"GATEWAY_INTERFACE\":\"CGI\\/1.1\",\"SERVER_SOFTWARE\":\"nginx\\/1.10.0\",\"REMOTE_ADDR\":\"127.0.0.1\",\"REMOTE_PORT\":\"49112\",\"SERVER_ADDR\":\"127.0.0.1\",\"SERVER_PORT\":\"80\",\"SERVER_NAME\":\"127.0.0.1\",\"REDIRECT_STATUS\":\"200\",\"HTTP_ACCEPT_ENCODING\":\"identity\",\"HTTP_CONTENT_LENGTH\":\"55731\",\"HTTP_HOST\":\"localhost\",\"HTTP_CONTENT_TYPE\":\"application\\/json\",\"HTTP_CONNECTION\":\"close\",\"HTTP_USER_AGENT\":\"Piwik\\/LogImport\",\"PHP_SELF\":\"\\/cBIMAX\\/src\\/piwik.php\",\"REQUEST_TIME_FLOAT\":1498140978.5635,\"REQUEST_TIME\":1498140978}},\"tokenAuth\":\"e750e87a0c9ee759f7dc97366a6ff61a\",\"time\":1498140978}"
1498140978.653064 [0 172.18.0.1:60496] "RPUSH" "trackingQueueV1_21" "{\"requests\":[{\"apiv\":\"1\",\"url\":\"http:\\/\\/live.csmtalk.vcdn.vn\\/hls\\/$tk$\\/\\/15c58c1a260\\/giaitritructiep\\/chunklist.m3u8\",\"cvar\":\"{\\\"1\\\": [\\\"HTTP-code\\\", \\\"410\\\"]}\",\"action_name\":\"410\\/URL = http%3A%2F%2Flive.csmtalk.vcdn.vn%2Fhls%2F%24tk%24%2F%2F15c58c1a260%2Fgiaitritructiep%2Fchunklist.m3u8\",\"cdt\":\"2017-05-31 07:00:27\",\"cip\":\"113.161.129.116\",\"urlref\":\"\",\"bw_bytes\":158,\"rec\":\"1\",\"_cvar\":\"{\\\"1\\\": [\\\"Not-Bot\\\", \\\"Mozilla\\/5.0 (Windows NT 6.1; rv:53.0) Gecko\\/20100101 Firefox\\/53.0\\\"]}\",\"idsite\":\"3\",\"bots\":\"1\",\"ua\":\"Mozilla\\/5.0 (Windows NT 6.1; rv:53.0) Gecko\\/20100101 Firefox\\/53.0\",\"dp\":\"1\"}],\"env\":{\"server\":{\"USER\":\"tony\",\"HOME\":\"\\/home\\/tony\",\"FCGI_ROLE\":\"RESPONDER\",\"PATH_INFO\":\"\",\"SCRIPT_FILENAME\":\"\\/home\\/tony\\/www\\/cBIMAX\\/src\\/piwik.php\",\"QUERY_STRING\":\"\",\"REQUEST_METHOD\":\"POST\",\"CONTENT_TYPE\":\"application\\/json\",\"CONTENT_LENGTH\":\"55731\",\"SCRIPT_NAME\":\"\\/cBIMAX\\/src\\/piwik.php\",\"REQUEST_URI\":\"\\/cBIMAX\\/src\\/piwik.php\",\"DOCUMENT_URI\":\"\\/cBIMAX\\/src\\/piwik.php\",\"DOCUMENT_ROOT\":\"\\/home\\/tony\\/www\",\"SERVER_PROTOCOL\":\"HTTP\\/1.1\",\"REQUEST_SCHEME\":\"http\",\"GATEWAY_INTERFACE\":\"CGI\\/1.1\",\"SERVER_SOFTWARE\":\"nginx\\/1.10.0\",\"REMOTE_ADDR\":\"127.0.0.1\",\"REMOTE_PORT\":\"49112\",\"SERVER_ADDR\":\"127.0.0.1\",\"SERVER_PORT\":\"80\",\"SERVER_NAME\":\"127.0.0.1\",\"REDIRECT_STATUS\":\"200\",\"HTTP_ACCEPT_ENCODING\":\"identity\",\"HTTP_CONTENT_LENGTH\":\"55731\",\"HTTP_HOST\":\"localhost\",\"HTTP_CONTENT_TYPE\":\"application\\/json\",\"HTTP_CONNECTION\":\"close\",\"HTTP_USER_AGENT\":\"Piwik\\/LogImport\",\"PHP_SELF\":\"\\/cBIMAX\\/src\\/piwik.php\",\"REQUEST_TIME_FLOAT\":1498140978.5635,\"REQUEST_TIME\":1498140978}},\"tokenAuth\":\"e750e87a0c9ee759f7dc97366a6ff61a\",\"time\":1498140978}"

anhnongdan commented 7 years ago

On server: try import log through scribe_pipe.13

try url https -> fail try url http -> 248:4005 -> fail

try log past, log real-time

try comment out if (always opt add site new host) -> when ctrl +c: root@VT-HNI-BIMAX-01:~/bimax_analytics1$ 134 lines parsed, 119 lines recorded, 2 records/sec (avg), 119 records/sec (current) -> might be problem with action or tracker, lines number are too small to show lines recorded realtime

-> yes, try to import large log (before splitting and extracting) 39372 lines parsed, 38400 lines recorded, 462 records/sec (avg), 0 records/sec (current) 39372 lines parsed, 38400 lines recorded, 456 records/sec (avg), 0 records/sec (current)

Problem: site is created but no log is import -> mysql cache???

anhnongdan commented 7 years ago

It's time to consider all the differences between Local-env, v3-env and v3standard-env:

Local and standard: php v5.6 (fpm on local and hhvm on server)
v3mode-env: php v7.0

anhnongdan commented 7 years ago

changed php on v3-mod to php5.6-hhvm => processlist on mysql showed up when importing logs:

| 555 | root  | localhost       | pw5  | Query   |    0 | init       | show processlist                                                                                     |    0.000 |
| 650 | admin | localhost:46622 | pw5  | Sleep   |    0 |            | NULL                                                                                                 |    0.000 |
| 651 | admin | localhost:46626 | pw5  | Sleep   |    0 |            | NULL                                                                                                 |    0.000 |
| 652 | admin | localhost:46648 | pw5  | Query   |    0 | statistics | SELECT MIN(idaction) as idaction, type, name FROM piwik_log_action WHERE ( hash = CRC32('410/URL = h |    0.000 |
| 653 | admin | localhost:46668 | pw5  | Sleep   |    0 |            | NULL                                                                                                 |    0.000 |
| 654 | admin | localhost:46674 | pw5  | Sleep   |    0 |            | NULL

anhnongdan commented 7 years ago

It seems that v3.0.1 work with VNPT log but there's always problem with Viettel log.

anhnongdan commented 7 years ago

Local: With VNPT log, log imported stuck in the queue.

=> need queuedtracking:process, but process one doesn't clear the queue, need many commands.

On server => Add var_dump to core/Tracker/Visit.php for debug 182: var_dump(get_class($processor));

-> it's seem nothing happen, removed the whole QueuedTracking folder, importing stop after a while.

Fatal error: HTTP Error 500 Internal Server Error, response: string(52) "Piwik\Plugins\CoreHome\Tracker\VisitRequestProcessor"
string(53) "Piwik\Plugins\Actions\Tracker\ActionsRequestProcessor"
{"status":"error","tracked":0,"invalid":0,"invalid_indices":[]}
You can restart the import of "(stdin)" from the point it failed by specifying --skip=147 on the command line.

Next, var_dump @ 122: => record as normal, no log printed.

var_dump @ plugins/QueuedTracking/Queue/Processor/Handler.php 99: => nothing show.

Run again: with https://viettelidc.bimax.tv/pw5 => look like there're 2 threads running:

20581 lines parsed, 16916 lines recorded, 994 records/sec (avg), 916 records/sec (current)
5141 lines parsed, 1880 lines recorded, 268 records/sec (avg), 1827 records/sec (current)
21219 lines parsed, 19200 lines recorded, 1065 records/sec (avg), 2284 records/sec (current)
5929 lines parsed, 2944 lines recorded, 367 records/sec (avg), 1064 records/sec (current)
22069 lines parsed, 19200 lines recorded, 1009 records/sec (avg), 0 records/sec (current)
6771 lines parsed, 2944 lines recorded, 326 records/sec (avg), 0 records/sec (current)
22880 lines parsed, 19200 lines recorded, 958 records/sec (avg), 0 records/sec (current)

anhnongdan commented 7 years ago

Continue on Server:

Use scribe_pipe.13 with NPIPE=1 => no log_link_visit_action imported but visit and action is imported correctly.

Try with realtime log for thvli. => nothing imported, may be log file has too few lines.
Try with realtime whole CDN: => 92614 | admin | localhost:58554 | pw5 | Query | 0 | update | INSERT INTO piwik_log_visit (idvisitor, config_id, location_ip, idsite, visit_first_action_time, vis | 0.000 |

=> truncate all table (also site), clean start:

anhnongdan commented 7 years ago

Just only 1 thing.

=> on local now: need to process queue to log to be imported in to DB. when importing, var_dump on Tracker code show up.

=> on server: queue will be automatically process some how. -> var_dump never show up.

anhnongdan commented 7 years ago

Disabled QueuedTracking plugin on Viettel server

=> problem remains.

Piwik import_log doesn't show any log
imports_log11.log show index out of range.
Shutdown DB => Piwik doesn't show any log about imports_log

Only when FE request fail, PW show DB connection fail. scribe_pipe show lines parsed without any line imported. imports_log.log show 500:

2017-06-27 17:07:26,586: [INFO] Error when connecting to Piwik: HTTP Error 500: Internal Server Error
2017-06-27 17:07:26,586: [INFO] Retrying request, attempt number 3
2017-06-27 17:07:26,622: [INFO] Error when connecting to Piwik: HTTP Error 500: Internal Server Error

anhnongdan commented 7 years ago

Try with standard version on Viettel server, now problem shows up.

=> disabled QueuedTracking plugin and problem remains Both scrive_pipe and extractor don't work

=> disable all the plugin: Annotation -> seems to work.

anhnongdan commented 7 years ago

On v3.0.1: deactive: Bandwidth Bulk Tracking

--- disable all plugins and still no luck

=> Disable Queuedtracking: => first time live data shows up on v3.0.1.

action and action_tracker still 0 -> enabled UserCountry, Live, Provider,

-> enable QueuedTracking and Tracker still work.

anhnongdan commented 7 years ago

it's running but still has problem with HHVM. => fixed (sv stop hhvm)

_Remember to monitor the log: docker-compose -f pw5.yml logs -f pw5

anhnongdan commented 7 years ago

Mean while on VNPT servers: queuedtracking is disabled and Extractor stopped -> start Extractor and enable Queuedtracking -> Work as normal.!!!

VNPT bimax is very laggy

11

anhnongdan commented 7 years ago

On VT pw2: start an instance with normal procedure. -> no log import (sites created OK) -> exact problem.

-> disable queuedtracking: no luck -> NO, AFTER SOME MINUTES, REALTIME COUNTER START TO WORK. -> reactivate QueuedTracking, -> add pw instance id to doAll() in flow.sh -> Still, no log in log_link and log_link_tracker

=> desc log_link_tracker -> threre's no:

 idpageview                   | char(6)              | YES  |     | NULL    |                |
| interaction_position         | smallint(5) unsigned | YES  |     | NULL    |                |

added row by hand and log is imported.

~~TODO: find out error log some where.~~ => see error log on db/data/[hostname].error

anhnongdan commented 7 years ago

There's 2 problems:

log_link_visit_action_tracker and log_link_visit_action is not consistent after enabling all plugins.
site_rollup table is not created.

anhnongdan commented 7 years ago

@TODO: Update on bimax_seed repo

anhnongdan commented 7 years ago

Fixed:

https://bitbucket.org/anhnongdan/bimax_seed/commits/a940f0aa979952bfaacdb61ceb840b47bffb898c https://bitbucket.org/anhnongdan/bimax_seed/commits/5a3715b25fd00cf6311d0fabeafc0beba4ba5a5f

anhnongdan / cBIMAX

[Deploy] cBimax can't import logs #9

Configure logging before calling logging.{debug,info}.

Logs import summary

Website import summary

Performance summary

11